cfn-initの実行時に「Unhandled exception during build: ‘utf8’ codec can’t decode byte…」のエラーが出る件について

Takuya Shibata

2020.10.31

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

しばたです。

CloudFormationでWindows Server EC2の初期設定をcfn-initヘルパースクリプトを使って実装しようとした際にとあるエラーでハマったので、その内容と回避策について本記事で共有します。

前提条件

今回問題が起きた環境は日本語Windows Server 2019 EC2インスタンスでcfn-initを実行する際に発生しています。
詳細は後述しますが、おそらく英語版Windows Serverでは発生せず非英語圏の言語版であれば他の言語でも発生しそうです。
Windowsのバージョンも関係なくどのバージョンでも発生すると思われます。

なおLinuxでは確認していないため同様の問題が発生するかは不明です。

何が起こったか？

cfn-initを使ってEC2インスタンスの初期設定のコマンドを実行した際に、コマンドの内容自体は正しいにも関わらず、

Unhandled exception during build: 'utf8' codec can't decode byte 0xnn in position nn: invalid start byte
(nnの部分はコマンドの内容により変わる)

といったエラーが発生しcfn-initが異常終了してしまう事象に遭遇しました。
cfn-init.logには以下の様な感じで出力されます。

cfn-init.log

2020-10-31 08:36:30,915 [ERROR] -----------------------BUILD FAILED!------------------------
2020-10-31 08:36:30,915 [ERROR] Unhandled exception during build: 'utf8' codec can't decode byte 0x83 in position 244: invalid start byte
Traceback (most recent call last):
  File "cfn-init", line 171, in <module>
  File "cfnbootstrap\construction.pyc", line 129, in build
  File "cfnbootstrap\construction.pyc", line 530, in build
  File "cfnbootstrap\construction.pyc", line 544, in run_config
  File "cfnbootstrap\construction.pyc", line 138, in run_commands
  File "cfnbootstrap\command_tool.pyc", line 120, in apply
  File "encodings\utf_8.pyc", line 16, in decode
UnicodeDecodeError: 'utf8' codec can't decode byte 0x83 in position 244: invalid start byte

発生頻度としてはコマンドが複雑な方が出やすいですが、内容が単純な場合でも発生する事があり、例えば以下の様なテンプレートでも再現させることができます。

AWSTemplateFormatVersion: 2010-09-09
Resources:

  # ・・・省略・・・

  # 最低限の部分のみ記載
  SampleEC2:
    Type: AWS::EC2::Instance
    Metadata:
      AWS::CloudFormation::Init:
        configSets:
          ascending:
            - config1
        config1:
          files:
            C:\cfn\do-something.ps1:
              content:
                Fn::Sub: |
                  Get-NetAdapter
          commands:
            0-do-something:
              command: powershell.exe -ExecutionPolicy Bypass C:\cfn\do-something.ps1
              waitAfterCompletion: 0
            1-signal-resource:
              command:
                Fn::Sub: |
                  cfn-signal.exe -e %ERRORLEVEL% --resource SampleEC2 --stack ${AWS::StackName} --region ${AWS::Region}   
    CreationPolicy:
      ResourceSignal:
        Count: 1
        Timeout: PT20M
    Properties:
      ImageId:
        Ref: WindowsLatestAmi
      UserData:
        Fn::Base64:
          Fn::Sub: |
            <script>
            cfn-init.exe -v -s ${AWS::StackId} -r SampleEC2 --configsets ascending --region ${AWS::Region}
            </script>

  # ・・・後略・・・

この内容ではC:\cfn\do-something.ps1というスクリプトを配備しGet-NetAdapterを実行する様にしているだけです。
通常実行すれば下図の様な結果を表示するだけですが、

実際には先述の通りのエラーとなり、cfn-init-cmd.logの詳細ログは以下の通り半端な出力を返します。

2020-10-31 08:36:23,680 P4536 [INFO] ============================================================
2020-10-31 08:36:23,680 P4536 [INFO] Command 0-do-something
2020-10-31 08:36:30,915 P4536 [INFO] -----------------------Command Output-----------------------
2020-10-31 08:36:30,915 P4536 [INFO] 	
2020-10-31 08:36:30,915 P4536 [INFO] 	Name                      InterfaceDescription                    ifIndex Status       MacAddress             LinkSpeed
2020-10-31 08:36:30,915 P4536 [INFO] 	----                      --------------------                    ------- ------       ----------             ---------
2020-10-31 08:36:30,915 P4536 [INFO] 	
2020-10-31 08:36:30,915 P4536 [INFO] 	
2020-10-31 08:36:30,915 P4536 [INFO] ------------------------------------------------------------

(7行目は本来ENIの情報が出力されるはずだが空になっている)

原因は？

根本原因は正直わかりません。

ただTwitterで頂いた情報^[1]によるとコマンドの出力に日本語が混ざる場合に起きるようです。
実際先述のGet-NetAdapterの場合は本来出力に「イーサネット 3」があり、ログからまさにその部分が欠落してしまっています。

具体的にどの様な文字種が混ざるとダメなのかまでは調査していませんが（というか無理）、エラー自体も明らかにエンコーディング周りで何か起きている風ですし、日本語全般がアウトと考えておいた方が良い気がしています。

また、こちらのブログによればcfn-initの-vオプションを除くことでログ出力を抑止して回避できたそうですが、私の場合は-vオプションを除いても問題は解消しませんでした。

回避策

根本原因は分かりませんが「日本語が出力されるとアウト」というのが分かれば回避策は割と容易です。

回避策1. コマンドの出力を抑止する

日本語を出力させなければ良いので[void]キャストや> $nullを使い出力自体を抑止してやればエラーは起きません。

# 通常のコマンドだと出力があるのでアウト
Get-NetAdapter

# voidキャストで出力を破棄する
[void](Get-NetAdapter)

# $nullリダイレクトで出力を破棄する
Get-NetAdapter *> $null

単純な方法ですが効果はあります。
ただし、実行結果を破棄してしまうのはデメリットも多いのでこの方法を使えるケースはさほど多くないでしょう。
コマンド自体が割と単純であるである場合、実行結果を気にしないで良い場合に使えます。

回避策2. 出力をファイルリダイレクトする

もう一つの回避策はコマンド出力を破棄するのでは無くファイルリダイレクトさせてしまうものです。

cfn-initは母体が組み込みPythonであり各コマンドの標準出力をキャプチャしています。
コマンドの結果をPython側に渡さずファイルリダイレクトでファイルに直接出力してしまえば、エラーを回避できる上にその内容も残ります。

# 通常のコマンドだと出力があるのでアウト
Get-NetAdapter

# ファイルリダイレクトで Python側への出力を回避
Get-NetAdapter *> C:\cfn\workaround.log

# コマンドのボリュームが多い場合は &{} の形式でスクリプトブロックでまとめてしまうと良い
&{
    Get-NetAdapter
    # 
    # do other many commands...
    #
} *> C:\cfn\workaround.log

PowerShell文法に関する補足

ここでPowerShellに不慣れな方に向けて軽く補足を入れておきます。

まずファイルリダイレクトの*>はPowerShell 3.0から利用可能な構文です。
これは他シェルの> 2>&1^[2]に近いものなのですが、PowerShellは他シェルと違い標準出力に相当するストリームというものがあり、ストリームは1>や2>以外に3> (Warning)、4> (Verbose)、5> (Debug)、6> (Information)まで存在します。
*>は全てのストリームの出力結果をまとめてリダイレクトする構文となります。

ストリームの詳細については個人ブログに書いてますのでこちらをご覧ください。

また、&{}については{}で複数の文を囲う事でスクリプトブロックとして宣言することができ、これは匿名関数のようなものだと考えてもらうとわかりやすいかと思います。
&は起動演算子と呼ばれ右オペランドにあるコマンドやスクリプトブロックを実行する演算子であり、&{}と書くことで宣言したスクリプトブロックを実行することができます。
最後に

&{
    # 
    # do many commands...
    #
} *> C:\cfn\workaround.log

の様に書くことで「一連の処理を匿名関数化し直ちに実行、匿名関数の出力をリダイレクトさせる」様な動作をさせることができます。
パフォーマンス的には若干不利になるのですが多くの処理がある場合にカジュアルに処理をまとめてリダイレクトできるためオススメです。

エラーを回避できるテンプレート例

ここまでを踏まえてエラーを回避できるテンプレートはこちらになります。
前節で説明したとおり&{}を使いコマンド全体をくくる様にしています。

AWSTemplateFormatVersion: 2010-09-09
Resources:

  # ・・・省略・・・

  # 最低限の部分のみ記載
  SampleEC2:
    Type: AWS::EC2::Instance
    Metadata:
      AWS::CloudFormation::Init:
        configSets:
          ascending:
            - config1
        config1:
          files:
            C:\cfn\do-something.ps1:
              content:
                Fn::Sub: |
                  # We need to privent to output NON-ASCII characters to stdout. 
                  &{
                      Get-NetAdapter
                  } *> C:\cfn\do-something.log
          commands:
            0-do-something:
              command: powershell.exe -ExecutionPolicy Bypass C:\cfn\do-something.ps1
              waitAfterCompletion: 0
            1-signal-resource:
              command:
                Fn::Sub: |
                  cfn-signal.exe -e %ERRORLEVEL% --resource SampleEC2 --stack ${AWS::StackName} --region ${AWS::Region}   
    CreationPolicy:
      ResourceSignal:
        Count: 1
        Timeout: PT20M
    Properties:
      ImageId:
        Ref: WindowsLatestAmi
      UserData:
        Fn::Base64:
          Fn::Sub: |
            <script>
            cfn-init.exe -v -s ${AWS::StackId} -r SampleEC2 --configsets ascending --region ${AWS::Region}
            </script>

  # ・・・後略・・・

実行結果もこんな感じでC:\cfn\do-something.psとC:\cfn\do-something.logが生成されています。

C:\cfn\do-something.logの中身はこんな風に良い感じに出力されています。

do-something.log

Name                      InterfaceDescription                    ifIndex Status       MacAddress             LinkSpeed
----                      --------------------                    ------- ------       ----------             ---------
イーサネット 3                  Amazon Elastic Network Adapter                8 Up           06-CC-09-48-5A-80        25 Gbps

もちろんcfn-init自体も正常終了しており、cfn-init.logの当該部分はこの様なエラー無く完了する様になりました。

cfn-init.log

2020-10-31 10:03:29,325 [DEBUG] Running command 0-do-something
2020-10-31 10:03:29,325 [DEBUG] No test for command 0-do-something
2020-10-31 10:03:34,796 [INFO] Command 0-do-something succeeded
2020-10-31 10:03:34,796 [DEBUG] Command 0-do-something output:

【2010.11.01追記】もう一つの回避策

最初にこの記事を公開した後でふと、

Python側がUTF-8を期待するなら [Console]::OutputEncoding を弄ってしまえばよいのでは？

と思い至り試してみました。
すなわち、スクリプトの先頭で[Console]::OutputEncoding = [System.Text.Encoding]::UTF8を仕込みコンソール出力のエンコーディングをUTF-8に強制する様にするわけです。

[Console]::OutputEncoding = [System.Text.Encoding]::UTF8
Get-NetAdapter

テンプレート全体だとこんな感じ。

AWSTemplateFormatVersion: 2010-09-09
Resources:

  # ・・・省略・・・

  # 最低限の部分のみ記載
  SampleEC2:
    Type: AWS::EC2::Instance
    Metadata:
      AWS::CloudFormation::Init:
        configSets:
          ascending:
            - config1
        config1:
          files:
            C:\cfn\do-something.ps1:
              content:
                Fn::Sub: |
                  # We need to specify [Console]::OutputEncoding to UTF8
                  [Console]::OutputEncoding = [System.Text.Encoding]::UTF8
                  Get-NetAdapter
          commands:
            0-do-something:
              command: powershell.exe -ExecutionPolicy Bypass C:\cfn\do-something.ps1
              waitAfterCompletion: 0
            1-signal-resource:
              command:
                Fn::Sub: |
                  cfn-signal.exe -e %ERRORLEVEL% --resource SampleEC2 --stack ${AWS::StackName} --region ${AWS::Region}   
    CreationPolicy:
      ResourceSignal:
        Count: 1
        Timeout: PT20M
    Properties:
      ImageId:
        Ref: WindowsLatestAmi
      UserData:
        Fn::Base64:
          Fn::Sub: |
            <script>
            cfn-init.exe -v -s ${AWS::StackId} -r SampleEC2 --configsets ascending --region ${AWS::Region}
            </script>

  # ・・・後略・・・

結果としてはこれでも期待した動作になりました。
cfn-init.logはこんな感じです。

cfn-init.log

2020-10-31 16:22:25,588 [DEBUG] Running command 0-do-something
2020-10-31 16:22:25,588 [DEBUG] No test for command 0-do-something
2020-10-31 16:22:31,509 [INFO] Command 0-do-something succeeded
2020-10-31 16:22:31,509 [DEBUG] Command 0-do-something output: 
Name                      InterfaceDescription                    ifIndex Status       MacAddress             LinkSpeed
----                      --------------------                    ------- ------       ----------             ---------
イーサネット 3                  Amazon Elastic Network Adapter                8 Up           06-12-C3-20-30-C2        25 Gbps